[asterisk-users] ConfBridge recording "Failed to get 160 samples from read factory" and "Read factory ... and write factory ... both fail to provide 160 samples"

Mon Oct 4 15:05:44 CDT 2021

We are running Asterisk 16.17.0 and discovered what we think is an issue.

We have a single call in a ConfBridge.
Tell the ConfBridge to start recording.
We see non-stop audiohook.c 160 samples failures.  As soon as we stop recording (AMI ConfBridgeStopRecord) these failures stop.

[10/04 14:57:57.109] DEBUG[2039] manager.c: Running action 'ConfbridgeStartRecord'
[10/04 14:57:57.109] DEBUG[2039] stasis.c: Creating topic. name: channel:1633377477.19, detail:
[10/04 14:57:57.109] DEBUG[2039] stasis.c: Topic 'channel:1633377477.19': 0x7fcc68016c00 created
[10/04 14:57:57.109] DEBUG[2039] stasis.c: Creating topic. name: cache:59/channel:1633377477.19, detail:
[10/04 14:57:57.109] DEBUG[2039] stasis.c: Topic 'cache:59/channel:1633377477.19': 0x7fcc68063e90 created
[10/04 14:57:57.109] DEBUG[2039] channel.c: Channel 0x7fcc680977a0 'CBRec/IS__OpBridge1-00000004' allocated
[10/04 14:57:57.109] DEBUG[2039] bridge_roles.c: Set role 'recorder'
[10/04 14:57:57.109] DEBUG[2039] autochan.c: Created autochan 0x7fcc6801bfa0 to hold channel CBRec/IS__OpBridge1-00000004 (0x7fcc680977a0)
[10/04 14:57:57.109] DEBUG[2530] bridge_channel.c: Bridge 44a7691f-bd48-40cd-9d05-4c2c3f482087: 0x7fcc68099d40(CBRec/IS__OpBridge1-00000004) is joining
[10/04 14:57:57.109] DEBUG[2530] bridge_channel.c: Bridge 44a7691f-bd48-40cd-9d05-4c2c3f482087: pushing 0x7fcc68099d40(CBRec/IS__OpBridge1-00000004)
[10/04 14:57:57.109] DEBUG[2530] bridge_roles.c: Set role 'recorder'
[10/04 14:57:57.109] DEBUG[2530] bridge.c: Bridge 44a7691f-bd48-40cd-9d05-4c2c3f482087: 0x7fcc68099d40(CBRec/IS__OpBridge1-00000004) is joining softmix technology
[10/04 14:57:57.109] DEBUG[2530] bridge_softmix.c:  CBRec/IS__OpBridge1-00000004:
[10/04 14:57:57.109] DEBUG[2529] audiohook.c: Read factory 0x7fcc680f3c88 and write factory 0x7fcc680f46c8 both fail to provide 160 samples
[10/04 14:57:57.109] DEBUG[2530] channel.c: Channel CBRec/IS__OpBridge1-00000004 setting write format path: slin -> slin
[10/04 14:57:57.109] DEBUG[2530] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[10/04 14:57:57.109] DEBUG[2530] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[10/04 14:57:57.109] DEBUG[2530] bridge_softmix.c:
[10/04 14:57:57.109] DEBUG[2530] bridge_softmix.c:  CBRec/IS__OpBridge1-00000004:
[10/04 14:57:57.109] DEBUG[2530] bridge_softmix.c:  CBRec/IS__OpBridge1-00000004: Not in SFU mode
[10/04 14:57:57.109] DEBUG[2039] manager.c: Examining AMI event:
Event: VarSet^M
Privilege: dialplan,all^M
Channel: PJSIP/1003-00000000^M
ChannelState: 6^M
ChannelStateDesc: Up^M
CallerIDNum: 1003^M
CallerIDName: 1003^M
ConnectedLineNum: <unknown>^M
ConnectedLineName: <unknown>^M
Language: en^M
AccountCode: 2^M
Context: IS^M
Exten: 333^M
Priority: 18^M
Uniqueid: 1633376893.0^M
Linkedid: 1633376893.0^M
Variable: BRIDGEPEER^M
Value: CBAnn/IS__OpBridge1-00000005;2,CBRec/IS__OpBridge1-00000004^M
^M

Event: ConfbridgeRecord^M
Privilege: call,all^M
Conference: IS__OpBridge1^M
BridgeUniqueid: 44a7691f-bd48-40cd-9d05-4c2c3f482087^M
BridgeType: base^M
BridgeTechnology: softmix^M
BridgeCreator: ConfBridge^M
BridgeName: IS__OpBridge1^M
BridgeNumChannels: 3^M
BridgeVideoSourceMode: none^M
^M

[10/04 14:57:57.128] DEBUG[2530] audiohook.c: Flushing audiohook 0x7fcc680f3c00 so it remains in sync
[10/04 14:57:57.128] DEBUG[2530] audiohook.c: Audiohook 0x7fcc680f3c00 has stale audio in its factories. Flushing them both
[10/04 14:57:57.128] DEBUG[2529] audiohook.c: Failed to get 160 samples from read factory 0x7fcc680f3c88
[10/04 14:57:57.128] DEBUG[2529] audiohook.c: Read factory 0x7fcc680f3c88 and write factory 0x7fcc680f46c8 both fail to provide 160 samples
[10/04 14:57:57.148] DEBUG[2529] audiohook.c: Failed to get 160 samples from read factory 0x7fcc680f3c88
[10/04 14:57:57.148] DEBUG[2529] audiohook.c: Read factory 0x7fcc680f3c88 and write factory 0x7fcc680f46c8 both fail to provide 160 samples
[10/04 14:57:57.168] DEBUG[2529] audiohook.c: Failed to get 160 samples from read factory 0x7fcc680f3c88
[10/04 14:57:57.168] DEBUG[2529] audiohook.c: Read factory 0x7fcc680f3c88 and write factory 0x7fcc680f46c8 both fail to provide 160 samples
[10/04 14:57:57.188] DEBUG[2529] audiohook.c: Failed to get 160 samples from read factory 0x7fcc680f3c88
[10/04 14:57:57.188] DEBUG[2529] audiohook.c: Read factory 0x7fcc680f3c88 and write factory 0x7fcc680f46c8 both fail to provide 160 samples
[10/04 14:57:57.208] DEBUG[2529] audiohook.c: Failed to get 160 samples from read factory 0x7fcc680f3c88
[10/04 14:57:57.208] DEBUG[2529] audiohook.c: Read factory 0x7fcc680f3c88 and write factory 0x7fcc680f46c8 both fail to provide 160 samples
[10/04 14:57:57.228] DEBUG[2529] audiohook.c: Failed to get 160 samples from read factory 0x7fcc680f3c88
[10/04 14:57:57.228] DEBUG[2529] audiohook.c: Read factory 0x7fcc680f3c88 and write factory 0x7fcc680f46c8 both fail to provide 160 samples
[10/04 14:57:57.248] DEBUG[2529] audiohook.c: Failed to get 160 samples from read factory 0x7fcc680f3c88
[10/04 14:57:57.248] DEBUG[2529] audiohook.c: Read factory 0x7fcc680f3c88 and write factory 0x7fcc680f46c8 both fail to provide 160 samples
[10/04 14:57:57.268] DEBUG[2529] audiohook.c: Failed to get 160 samples from read factory 0x7fcc680f3c88
....
[10/04 15:01:32.248] DEBUG[2529] audiohook.c: Failed to get 160 samples from read factory 0x7fcc680f3c88
[10/04 15:01:32.248] DEBUG[2529] audiohook.c: Read factory 0x7fcc680f3c88 and write factory 0x7fcc680f46c8 both fail to provide 160 samples
[10/04 15:01:32.268] DEBUG[2529] audiohook.c: Failed to get 160 samples from read factory 0x7fcc680f3c88
[10/04 15:01:32.268] DEBUG[2529] audiohook.c: Read factory 0x7fcc680f3c88 and write factory 0x7fcc680f46c8 both fail to provide 160 samples
[10/04 15:01:32.288] DEBUG[2529] audiohook.c: Failed to get 160 samples from read factory 0x7fcc680f3c88
[10/04 15:01:32.288] DEBUG[2529] audiohook.c: Read factory 0x7fcc680f3c88 and write factory 0x7fcc680f46c8 both fail to provide 160 samples
[10/04 15:01:32.296] DEBUG[2039] manager.c: Running action 'ConfbridgeStopRecord'
[10/04 15:01:32.296] DEBUG[2530] bridge_channel.c: Setting 0x7fcc68099d40(CBRec/IS__OpBridge1-00000004) state from:0 to:1
[10/04 15:01:32.296] DEBUG[2530] bridge_channel.c: Bridge 44a7691f-bd48-40cd-9d05-4c2c3f482087: pulling 0x7fcc68099d40(CBRec/IS__OpBridge1-00000004)
[10/04 15:01:32.296] DEBUG[2530] bridge_channel.c: Bridge 44a7691f-bd48-40cd-9d05-4c2c3f482087: 0x7fcc68099d40(CBRec/IS__OpBridge1-00000004) is leaving softmix technology
[10/04 15:01:32.296] DEBUG[2530] channel.c: Channel 0x7fcc680977a0 'CBRec/IS__OpBridge1-00000004' hanging up.  Refs: 3
[10/04 15:01:32.296] DEBUG[2529] autochan.c: Removed autochan 0x7fcc6801bfa0 from the list, about to free it
[10/04 15:01:32.296] DEBUG[2529] channel.c: Channel 0x7fcc680977a0 'CBRec/IS__OpBridge1-00000004' destroying
[10/04 15:01:32.296] DEBUG[2039] manager.c: Examining AMI event:
Event: ConfbridgeStopRecord^M
Privilege: call,all^M
Conference: IS__OpBridge1^M
BridgeUniqueid: 44a7691f-bd48-40cd-9d05-4c2c3f482087^M
BridgeType: base^M
BridgeTechnology: softmix^M
BridgeCreator: ConfBridge^M
BridgeName: IS__OpBridge1^M
BridgeNumChannels: 3^M
BridgeVideoSourceMode: none^M
^M

[10/04 15:01:32.296] DEBUG[2529] stasis.c: Destroying topic. name: cache:59/channel:1633377477.19, detail:
[10/04 15:01:32.296] DEBUG[2529] stasis.c: Topic 'cache:59/channel:1633377477.19': 0x7fcc68063e90 destroyed
[10/04 15:01:32.296] DEBUG[2529] stasis.c: Destroying topic. name: channel:1633377477.19, detail:
[10/04 15:01:32.296] DEBUG[2529] stasis.c: Topic 'channel:1633377477.19': 0x7fcc68016c00 destroyed
[10/04 15:01:32.296] DEBUG[2039] manager.c: Examining AMI event:
Event: VarSet^M
Privilege: dialplan,all^M
Channel: PJSIP/1003-00000000^M
ChannelState: 6^M
ChannelStateDesc: Up^M
CallerIDNum: 1003^M
CallerIDName: 1003^M
ConnectedLineNum: <unknown>^M
ConnectedLineName: <unknown>^M
Language: en^M
AccountCode: 2^M
Context: IS^M
Exten: 333^M
Priority: 18^M
Uniqueid: 1633376893.0^M
Linkedid: 1633376893.0^M
Variable: BRIDGEPEER^M
Value: CBAnn/IS__OpBridge1-00000005;2^M
^M

[10/04 15:01:32.296] DEBUG[2529] app_mixmonitor.c: No recipients to forward monitor to, moving on.
[10/04 15:01:32.296] DEBUG[1752] devicestate.c: No provider found, checking channel drivers for CBRec - IS__OpBridge1
[10/04 15:01:32.296] DEBUG[1752] devicestate.c: Changing state for CBRec/IS__OpBridge1 - state 0 (Unknown)

How do we stop these from happening?
If the failure is happening, seems it would have issues to the system.

This email is intended only for the use of the party to which it is addressed and may contain information that is privileged, confidential, or protected by law. If you are not the intended recipient you are hereby notified that any dissemination, copying or distribution of this email or its contents is strictly prohibited. If you have received this message in error, please notify us immediately by replying to the message and deleting it from your computer.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20211004/5607a75f/attachment.html>