CAM left in unusable state after ca_request_close()

[Jalle19]

When an incomplete write occurs, the CAM ends up being unusable until minisatip is restarted:

[21/04 22:12:51.331 AD7]: incomplete write to CA 7 fd 24, expected 5 got -1, errno 5 Input/output error

Since v1.2, ca_request_close() is called which just closes the CAM socket. Before, a proper reset was issued:

ioctl(fd, CA_RESET, &info)

[Jalle19]

@catalinii what's your opinion on changing this back to using CA_RESET?

[Yuri666]

i can confirm the issue
log.txt.zip

[catalinii]

Yeah changing back to uninitialized state and using CA_RESET should work

[Jalle19]

Turns out that closing the socket triggers the logic in the ca_reconnect poller, which calls dvbca_init_dev() which calls ca_init_en50221 which does ioctl(fd, CA_RESET, &info), so the issue doesn't seem to be that the device isn't getting reset properly. There's something else that causes minisatip to lose the ability to actually use the CAM for decryption after a reset, but I'm not sure where.

[catalinii]

Can you enable -v ca when that happens and post the log?

[Jalle19]

It happens exceedingly rarely, less than once a month for me. IIRC -v ca prints so much that I end up running out of disk space, but I'll see if I can enable it.

[Yuri666]

To reproduce this just needs pull and put card to CAM

[Jalle19]

Could be related to why things don't work after a CAM reset:

May 26 14:52:21 vladimir minisatip[51448]: [26/05 14:52:21.363 main]: ad 9 [9], another update_pids is in progress skipping
May 26 14:52:21 vladimir minisatip[51448]: [26/05 14:52:21.363 main]: CAPMT not found for pmt 11
May 26 14:52:21 vladimir minisatip[51448]: [26/05 14:52:21.363 main]: Skip deleting pmt for ddci adapter 9

Oddly this (incomplete write) happened to me today at almost the exact same time, and almost exactly 12 hours since minisatip was started (I restart it at 3 AM every night):

$ journalctl -u minisatip | grep 'incomplete write'
May 25 14:50:33 vladimir minisatip[47662]: [25/05 14:50:33.427 AD9]: incomplete write to CA 9 fd 28, expected 5 got -1, errno 5 Input/ou
May 26 14:51:49 vladimir minisatip[51448]: [26/05 14:51:49.803 AD9]: incomplete write to CA 9 fd 28, expected 5 got -1, errno 5 Input/ou

[Jalle19]

Actually no, the "another update_pids is in progress skipping" happens regularly, so probably not related

[Jalle19]

Aha, but CAPMT not found for pmt X only appears after a CAM reset

[Jalle19]

Trying this for the time being:

const { spawn } = require('child_process')
const Journalctl = require('@seydx/journalctl')

const journalctl = new Journalctl({
  unit: 'minisatip',
})

journalctl.on('event', (event) => {
  const message = event['MESSAGE']

  if (message.includes('incomplete write')) {
    console.log(`Received offending log line, restarting: ${message}`)

    spawn('systemctl', ['restart', 'minisatip'])
  }
})